Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix: remove ops.main.main deprecation warning, and avoid warnings in action output #1496

Merged
merged 13 commits into from
Jan 23, 2025

Conversation

tonyandrewmeyer
Copy link
Contributor

@tonyandrewmeyer tonyandrewmeyer commented Dec 10, 2024

Background:

  • A warnings.warn call outputs to stderr by default.
  • Juju captures stderr and when executing an action provides it to the user.
  • We emit a DeprecationWarning when charms call main() other than import ops ... ops.main()
  • DeprecationWarnings are ignored by default, except for issues in the __main__ module.
  • A warning like this is meant to be discovered during tests - but unit tests typically do not call main() or execute the charm.py file, so they will not trigger this warning. That means that we're relying on integration tests.

The above means that, currently, the deprecation warning is included in the action output - this warning is intended for the developer of the charm, not the user of the charm, so we want to change this.

Firstly, the ops.main.main deprecation warning is removed. It's too awkward to have a warning that gets emitted before the framework is set up. Instead, we'll rely on charmcraft analyse and static checks.

However, while that will solve the specific issue in #1460, we do also want to avoid any future leakage of warnings into action output if there are other warnings emitted that originate in the __main__ model.

To that, rather than rely on Juju capturing the warning via stderr, we use the logging package to capture all warnings and redirect them to logging calls. These are then directed to Juju's debug-log via the existing mechanism. While we are doing this, we minimise the output to include references to the filename and line, but not the actual code itself (which may be sensitive).

When running (Scenario) tests, we ensure that the warning and logging systems use their default behaviour, so that pytest and other tools can work as expected.

Fixes #1460

@tonyandrewmeyer
Copy link
Contributor Author

The PR uses the second option, which seems cleaner - the main drawback is that if someone is running the charm with a custom warning filter, such as -W error::DeprecationWarning, then that won't match this warning.

Thinking on this more, I think it should be the other one. I'll switch over (and fix whatever the test issue is - maybe 3.8 compatibility since they passed locally) and un-draft. No need to review until then.

ops/main.py Outdated Show resolved Hide resolved
ops/main.py Outdated Show resolved Hide resolved
ops/main.py Outdated Show resolved Hide resolved
ops/main.py Outdated Show resolved Hide resolved
@dimaqq
Copy link
Contributor

dimaqq commented Dec 11, 2024

The two options for this are:

  • Customise the warnings formatting, just around this specific warning.
  • Output the warning in another way (printing or logging, for example).

I think there's a 3rd option: remove the warning entirely, and solve the ops.main.main -> ops.main some other way:

  • better type hints (?)
  • charmcraft lint
  • github search, leading to opening PRs to charmers' repos
  • or something

Let's brainstorm at the next standup, perhaps?

@tonyandrewmeyer
Copy link
Contributor Author

I think there's a 3rd option: remove the warning entirely

I did think about this too. This one in particular is complicated because it's "outside" the charm, so it doesn't get picked up in unit tests and is also complicated to code around because the framework isn't set up yet.

I do think that we should have a PR that prevents the general issue of DeprecationWarnings that caused by code in src/charm.py ending up in action output. But we could potentially do that and also give up on this specific warning in favour of other approaches.

@benhoyt
Copy link
Collaborator

benhoyt commented Dec 17, 2024

Decision from Charm Tech is to remove the warning altogether to keep it simple. And then Charm Tech (whoever works on this) can open 2 or 3 PRs jubilantly (!) to fix this in the "culprit teams".

@tonyandrewmeyer tonyandrewmeyer marked this pull request as ready for review December 18, 2024 09:45
@tonyandrewmeyer
Copy link
Contributor Author

And then Charm Tech (whoever works on this) can open 2 or 3 PRs jubilantly (!) to fix this in the "culprit teams".

Yoikes:

tameyer@tam-canoncial-1:~/code/charm-analysis/.cache$ rg 'from ops.main import main' -l | wc -l
312

@tonyandrewmeyer tonyandrewmeyer changed the title fix: warn about deprecated ops.main calls after the framework is set up fix: remove ops.main.main deprecation warning, and avoid warnings in action output Dec 18, 2024
@benhoyt
Copy link
Collaborator

benhoyt commented Dec 18, 2024

Yoikes:

tameyer@tam-canoncial-1:~/code/charm-analysis/.cache$ rg 'from ops.main import main' -l | wc -l
312

Ouch. We could still let 2 or 3 teams know with PRs, but yeah, with those numbers, maybe that's not a good approach. I guess just a polite message in Charm Development and leave it at that?

Out of interest, are there 312 charms in your dir now, or does this occur more than once per charm?

@tonyandrewmeyer
Copy link
Contributor Author

Out of interest, are there 312 charms in your dir now, or does this occur more than once per charm?

More than once. Some are documentation, but that really ought to get fixed too. Some are in libs, so there's some duplication that would remove the number of PRs, but be more annoying to make sure the change is in the right PR. Some repos also have quite a few charms in them, which ups the volume.

$ rg 'from ops.main import main' -l | grep -v 'lib/charms' | grep -v 'tests/integration' | wc -l
161

ops/log.py Show resolved Hide resolved
@tonyandrewmeyer tonyandrewmeyer requested a review from dimaqq January 8, 2025 23:01
ops/log.py Outdated Show resolved Hide resolved
**__: typing.Any,
):
"""Direct the warning to Juju's debug-log, and don't include the code."""
logger.warning('%s:%s: %s: %s', filename, lineno, category.__name__, message)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

what do you think about using warnings.formatwarning(...) to replicate what showwarning does, that is tries to load the source code and show where the warning was issued?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't like unstructured log entries that have newlines in them, and I don't think it's ideal to have code snippets in the Juju debug log. However, we do both of those for exceptions already, so perhaps that doesn't matter. However, I don't think it's that useful for warnings. The default warnings formatter looks like:

/tmp/fw.py:4: DeprecationWarning: Don't call foo(), use the new bar() instead
  warnings.warn("Don't call foo(), use the new bar() instead", DeprecationWarning)

That second line is telling me nothing that the first line hasn't already. Maybe the line has something other than the warnings.warn call that provides extra context, but in my experience that's unusual.

That would currently show something like:

unit-my-charm-0: 10:07:20 INFO unit.my-charm/0.juju-log charm.py:42: DeprecationWarning: Don't call foo(), use the new bar() instead

I feel like that's a better form for an unstructured log message.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I guess that depends on whether the end user looks at single messages are series of messages.

Don't call foo(), use the new bar() instead is great if there's a single call to foo(), and not so much if there are hundreds, or if there's no obvious call, as in a case of being called via getattr(<computed>)().

I can see benefits for both alternatives, I guess.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Don't call foo(), use the new bar() instead is great if there's a single call to foo(), and not so much if there are hundreds, or if there's no obvious call, as in a case of being called via getattr(<computed>)().

But you still have the filename and the line number. You don't have the exact line of code, but assuming you have access to it, it's trivial to open that file and go to that line number. You don't get a full traceback with the default formatter, so you only have the line the warning was pointing at - which is hopefully using a stacklevel that is one up from the actual warning.warn call.

For example:

# charm.py
class MyCharm(ops.CharmBase):
    ...
    def _on_something(self, event):
        self.foo() # first one
        ...

    def _on_something_else(self, event):
        self.foo() # second one

    def foo(self):
        warnings.warn("don't foo(), do bar()", DeprecationWarning, stacklevel=2)

When _on_something is called, there will be a Juju log entry that points you at charm.py to the line with "# first one", and when on_something_else is called, there will be a Juju log entry that points you at charm.py to the line with "# second one".

If we include the actual code, like the default formatter, then you'd also have in the Juju debug log those actual lines of code, but I don't think this really gains you much (especially when it's a warning aimed at the developer, who will have access to the code) - and it saves having a multi-line log entry.

test/test_main_invocation.py Show resolved Hide resolved
@tonyandrewmeyer
Copy link
Contributor Author

@benhoyt friendly reminder about this PR in case it's slipped off your radar :)

Copy link
Collaborator

@benhoyt benhoyt left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, it had indeed slipped off my radar. I'm happy with this -- thanks!

@tonyandrewmeyer tonyandrewmeyer merged commit 758ee43 into canonical:main Jan 23, 2025
32 checks passed
@tonyandrewmeyer tonyandrewmeyer deleted the cleaner-warnings-1460 branch January 23, 2025 00:35
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

should actions leak deprecation warnings?
3 participants